最近在寫一些 side project 時碰到了一些 bug ，這個時候除了用 println! 大法外，如果有好好的寫 log 或許也會比較容易知道發生了什麼事，這篇就來整理一下我用過的 Rust 的 log 框架

log

這個其實在之前的文章中就有提到了，不過那個時候幾乎沒有介紹，這次就來好好的介紹一下， log 是 Rust 的社群所約定的一個 log 的標準，想輸出 log 的人使用 log 的 API ，而應用程式只要使用實作了 log 中的 trait 的 Logger就能顯示 log

這邊是最基本的使用方式與 Logger 的實作：

use log::{info, LevelFilter, Log, Metadata, Record};

struct Logger;

impl Log for Logger {
    // 提供讓使用者偵測有沒有啟用 log 的 API
    fn enabled(&self, _meta: &Metadata) -> bool {
        true
    }

    // 實際輸出 log 的部份
    fn log(&self, record: &Record) {
        eprintln!("{}: {}", record.level(), record.args());
    }

    // 清空緩衝區
    fn flush(&self) {}
}

// 一般 Logger 會提供一個函式讓使用者設定 Logger
fn init_log() {
    static LOGGER: Logger = Logger;
    log::set_max_level(LevelFilter::Trace);
    log::set_logger(&LOGGER).unwrap();
}

fn main() {
    init_log();
    info!("Hello world")
}

而我自己喜歡用的兩個 logger ，分別是：

• pretty_env_logger: 這個提供了 env_logger 有的功能，同時輸出又比 env_logger 預設的要來的好看，不過它其實只是修改了 env_logger 預設的樣式而已
• fern: 一個彈性頗高的 logger ，可以設定同時輸出到螢幕跟檔案之類的

不過 log 就只能輸出文字訊息而已，如果要輸出變數的內容就要自己用 format string 把它加入訊息中：

let foo = 1;
info!("foo = {}", foo);

如果變數不多，這好像也不是什麼大問題，但假如多的話呢？而且還有另一個情況，現在有些情況下會希望輸出的 log 是方便程式處理的格式，比如 json ，但 log 這樣輸出的方法就只能是文字訊息而已，如果能把變數內容加到 json 中，對於要處理的程式而言就更方便了

目前 log 有打算要支援 structured logging (issue) ，不過什麼時候才會支援就不知道了

slog

slog 是個 structured logging 的框架，讓你可以依自己的需求組合出自己的 logger ，另外也有提供相容於 log 的功能，不過如果使用來自 log 的 macro 就沒辦法使用 structured logging 的功能了

此外因為可以自己組合 logger 的關係，在使用上也是比較複雜的，比如這邊簡單弄一個輸出成 json 的 logger ：

use slog::Drain;
use std::sync::Mutex;

fn main() {
    let root = slog::Logger::root(
        Mutex::new(slog_json::Json::default(std::io::stderr())).fuse(),
        // 讓每行 log 都會帶有版本號的資訊， slog::o! 代表的是包裝成 `OwnedKV`
        slog::o!("version" => env!("CARGO_PKG_VERSION")),
    );
    // 輸出 Hello world ，同時帶一組 key value 為 "foo" => 1
    slog::info!(&root, "Hello world"; "foo" => 1);
}

這邊其實還有很多的小細節，比如我們還用到了 Mutex ，另外還有 fuse 跟 Drain 又是什麼之類的，首先先從 Drain 這個 trait 開始，它是 slog 輸出 log 的目標，所以 log 要輸出到檔案，要用什麼樣的格式，基本上最後都是要在這個 trait 的實作中決定， slog 有提供一個空白實作的 Discard 用來當作完全不輸出的 Drain ，同時也是一個很好的實作範例：

#[derive(Debug, Copy, Clone)]
pub struct Discard;

impl Drain for Discard {
    type Ok = ();
    // Never 是 slog 用來代表不可能會有錯誤的一個型態，這邊就不管了
    type Err = Never;
    fn log(&self, _: &Record, _: &OwnedKVList) -> result::Result<(), Never> {
        Ok(())
    }
    // 這邊就跟 log::Logger 一樣，可以用來檢查要不要輸出這個 log
    #[inline]
    fn is_enabled(&self, _1: Level) -> bool {
        false
    }
}

其中的 log 就是輸出的部份， slog 的 Record 基本上有 log 的 Record 所有的資訊，只是還多了一個 key value pair 的部份，以上面來說就是 foo 的那部份，另外還有 OwnedKVList 則是在建立 logger 時傳進的 key value pair ，以上面來說則是 version 的部份

另外上面也可以看到 Drain 的 log 是可以回傳 Err 代表自己沒辦法正常輸出 log 的，但 slog 要求傳入 logger 的 Drain 必須要處理掉 Err ，因此就有 fuse 跟另一個函式可以用了：

• fuse: 它會包裝你提供的 Drain ，並在回傳 Err 時 panic
• ignore_res: 忽略 Drain 回傳的錯誤

最後則是 Mutex 的部份，因為 slog 要求 logger 必須能支援多執行緒，如果你的 Drain 並不支援的話，這邊就有兩種做法，一種是用 Mutex 包裝， Drain 也有實作由 Mutex 包裝的 Drain ，它會在要輸出 log 時鎖上，另一個則是使用 slog-async 這個 crate ，它用 channel 把 log 送到另一個執行緒來輸出

這邊再來組一個比較複雜的 logger 吧，我們把 json 輸出到檔案，然後輸出好看的 log 到 stderr ：

use slog::{Drain, Duplicate};
use std::fs::File;

fn main() {
    let log_file = File::create("test.log").unwrap();
    let json_drain = slog_json::Json::default(log_file).fuse();
    let decorator = slog_term::TermDecorator::new().build();
    let drain = slog_term::CompactFormat::new(decorator).build().fuse();
    let drain = slog_async::Async::new(Duplicate::new(drain, json_drain).fuse())
        .build()
        .fuse();

    let root = slog::Logger::root(drain, slog::o!());

    slog::info!(&root, "Hello world"; "foo" => 1);
}

這邊用 slog-term 輸出好看的 log ，然後用 slog::Duplicate 來同時輸出到兩個不同的 Drain ，像這樣就可以客制化自己需要的 logger

最後你可能會注意到 slog 都需要傳入 logger 的 instance ，那是因為它可以有子 logger ，比如：

use slog::Drain;

fn main() {
    let decorator = slog_term::TermDecorator::new().build();
    let drain = slog_term::CompactFormat::new(decorator).build().fuse();
    let drain = slog_async::Async::new(drain).build().fuse();
    let root = slog::Logger::root(drain, slog::o!("logger" => "root"));
    let child = root.new(slog::o!("logger" => "child"));
    slog::info!(&root, "Hello world");
    slog::info!(&child, "Using child");
}

像這樣可以比如幫不同的元件設定不同的 logger ，讓它們顯示自己來自哪個元件，不過大部份的函式庫用的應該都是社群標準的 log ，這時候能個整合原本的 log 就變的很重要了：

use slog::Drain;

fn main() {
    let decorator = slog_term::TermDecorator::new().build();
    let drain = slog_term::FullFormat::new(decorator).build().fuse();
    let drain = slog_async::Async::new(drain).build().fuse();
    let logger = slog::Logger::root(drain, slog::o!("version" => env!("CARGO_PKG_VERSION")));

    // 設定全域的 slog
    let _scope_guard = slog_scope::set_global_logger(logger);
    // 把 log 導到 slog
    slog_stdlog::init().unwrap();
    log::info!("standard logging redirected to slog");
}

這邊用到了兩個 crate ，分別是 slog-scope 與 slog-stdlog ，第一個是讓使用者可以從這個 crate 取得 logger 或是設定 logger ，而 stdlog 則是把 log 導到由 scope 設定的 logger 去，執行上面的範例應該就會看到 log 的輸出被導向給 slog 處理了

tracing

不過隨著 async/await 的出現， slog 這樣的 structured log 好像又不太夠用了，像在多執行緒或是有 async/await 的情況下，工作是可以交錯執行的，自然 log 的輸出也會交錯，在底下又使用到了只用 log 輸出 log 的第三方函式庫的話，交錯輸出的 log 反而只是讓 debug 變的更困難罷了，不過 slog-scope 還是有辦法處理多執行緒的情況的：

use rayon::prelude::*;
use slog::Drain;
use std::{thread, time::Duration};

fn thrid_party() {
    log::info!("start process");
    thread::sleep(Duration::from_secs(1));
    log::info!("end process");
}

fn main() {
    let decorator = slog_term::TermDecorator::new().build();
    let drain = slog_term::FullFormat::new(decorator).build().fuse();
    let drain = slog_async::Async::new(drain).build().fuse();
    let root = slog::Logger::root(drain, slog::o!("version" => env!("CARGO_PKG_VERSION")));
    let _guard = slog_scope::set_global_logger(root);
    slog_stdlog::init().unwrap();

    let data = vec![1, 2, 3, 4, 5, 6];

    data.into_par_iter().for_each(|n| {
        slog_scope::scope(&slog_scope::logger().new(slog::o!("data" => n)), || {
            thrid_party();
        });
    });
}

像這樣就可以幫只用 log 的函式加上目前在處理的資料，或是任務的 id 等等，不過 slog 就沒辦法用這種方式支援 async/await 了， slog 的 scope 目前是以 thread local variable 來實作的，但 async/await 的程式可能是在同一個 thread 中去切換程式執行的流程，這時候的 scope 就不會正確了，這時候 Rust 社群中就我所知大概是最早就在做 async 的執行環境的 tokio 就出了一個 tracing 的 log 框架，這邊先來看個範例:

use tracing_subscriber::{fmt, layer::SubscriberExt, util::SubscriberInitExt};

fn main() {
    tracing_subscriber::registry()
        .with(fmt::layer())
        .init();
    
    // 注意這邊是呼叫 `log` 的 macro ，而不是 `tracing` 的
    log::info!("Hello world");
    
    let foo = 42;
    tracing::info!(foo, "Hello from tracing");
}

沒意外的話你應該會看見兩條 log ，一條是從 log 來的，另一條才是 tracing 來的，從這邊你可以注意到，其實 tracing 預設就已經支援整合 log 了，至於它跟 log 或 slog 有什麼不同呢？這邊來用它最重要的功能 span ：

use tracing::{debug, info, span, Level};
use tracing_subscriber::{fmt, layer::SubscriberExt, util::SubscriberInitExt};

fn main() {
    tracing_subscriber::registry().with(fmt::layer()).init();

    let scope = span!(Level::DEBUG, "foo");
    let _enter = scope.enter();
    info!("Hello in foo scope");
    debug!("before enter bar scope");
    {
        let scope = span!(Level::DEBUG, "bar", ans = 42);
        let _enter = scope.enter();
        debug!("enter bar scope");
        info!("In bar scope");
        debug!("end bar scope");
    }
    debug!("end bar scope");
}

像這樣它可以用來劃分程式的區域，而區域的名字，與放在裡面的資訊都會被加入 log 中，像這樣：

 INFO foo: log_test: Hello in foo scope
DEBUG foo: log_test: before enter bar scope
DEBUG foo:bar{ans=42}: log_test: enter bar scope
 INFO foo:bar{ans=42}: log_test: In bar scope
DEBUG foo:bar{ans=42}: log_test: end bar scope
DEBUG foo: log_test: end bar scope

以我的理解 span 的第一個參數應該要能控制這個 span 輸出的等級才是，但不知道這邊為什麼不行，如果有人知道希望可以告訴我

而這個功能也可以用在 future 或是 async fn 上，比如使用 instrument 這個 macro 來自動建立函式的 span ：

use tracing::{info, instrument};
use tracing_subscriber::{fmt, layer::SubscriberExt, util::SubscriberInitExt};

#[instrument]
fn foo(ans: i32) {
    info!("in foo");
}

fn main() {
    tracing_subscriber::registry().with(fmt::layer()).init();
    foo(42);
}

它輸出的 log 會像這樣：

INFO foo{ans=42}: log_test: in foo

這個東西也可以用在 async function 上，不過要另外安裝 tracing-futures 就是了，這邊跑兩個 async function 來展示吧：

use std::time::Duration;
use tracing::{info,  instrument, Level};
use tracing_subscriber::{fmt, filter::LevelFilter, layer::SubscriberExt, util::SubscriberInitExt};

// 可以用 skip 讓 tracing 不要印出某些參數
#[instrument(skip(delay))]
async fn work(id: i32, delay: u64) {
    info!("start work");
    for i in 0..5 {
        info!("loop {}", i);
        smol::Timer::after(Duration::from_secs(delay)).await;
    }
    info!("end work");
}

fn main() {
    tracing_subscriber::registry().with(LevelFilter::from_level(Level::INFO)).with(fmt::layer()).init();

    smol::block_on(async {
        let task = smol::spawn(work(1, 2));
        let task2 = smol::spawn(work(2, 3));
        task.await;
        task2.await;
    });
}

這邊用 smol 這個比較小的 async runtime 來展示在 async fn 的 log ，雖然 log 會交錯在一起，但每行都會有函式相關的資訊，這樣就不會搞混了

INFO work{id=1}: log_test: start work
INFO work{id=1}: log_test: loop 0
INFO work{id=2}: log_test: start work
INFO work{id=2}: log_test: loop 0
INFO work{id=1}: log_test: loop 1
INFO work{id=2}: log_test: loop 1
INFO work{id=1}: log_test: loop 2
INFO work{id=2}: log_test: loop 2
INFO work{id=1}: log_test: loop 3
INFO work{id=1}: log_test: loop 4
INFO work{id=2}: log_test: loop 3
INFO work{id=1}: log_test: end work
INFO work{id=2}: log_test: loop 4
INFO work{id=2}: log_test: end work

最後來弄一個複雜一點的設定吧，這次除了 tracing 系列的還會用到 color-eyre ，這邊同樣的讓 log 同時輸出到畫面上與檔案中

color-eyre 是個提供可以讓任何的 error 包裝成它的 Report 與 panic 時顯示 backtrace 的 crate ，建議去看它的範例

use color_eyre::{eyre::eyre, Result};
use tracing::{error, info, instrument};
use tracing_appender::{non_blocking, rolling};
use tracing_error::ErrorLayer;
use tracing_subscriber::{
    filter::EnvFilter, fmt, layer::SubscriberExt, util::SubscriberInitExt, Registry,
};

#[instrument]
fn return_err() -> Result<()> {
    Err(eyre!("Something went wrong"))
}

#[instrument]
fn call_return_err() {
    info!("going to log error");
    if let Err(err) = return_err() {
        // 推薦實際跑一次，看看這邊是怎麼輸出的，你會發現 tracing 搭配 color-eyre 是多麼的強大
        error!(?err, "error");
    }
}

fn main() -> Result<()> {
    let env_filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("info"));
    // 這邊是輸出到畫面的 subscriber
    let formatting_layer = fmt::layer().pretty().with_writer(std::io::stderr);
    
    // 這邊是輸出到檔案的
    let file_appender = rolling::never("logs", "app.log");
    let (non_blocking_appender, _guard) = non_blocking(file_appender);
    let file_layer = fmt::layer()
        .with_ansi(false)
        .with_writer(non_blocking_appender);
        
    // 把兩個都註冊上去
    Registry::default()
        .with(env_filter)
        // ErrorLayer 是讓 color-eyre 可以抓到 span 的資訊用的
        .with(ErrorLayer::default())
        .with(formatting_layer)
        .with(file_layer)
        .init();
    
    // 安裝 color-eyre 的 panic handler ，不過這次的程式沒有 panic
    color_eyre::install()?;

    call_return_err();

    Ok(())
}

結語

這段是個人的想法，就請參考就好， Rust 的 log 的生態系看來暫時會分成使用 log 與 tracing 的兩大派吧 ， slog 如果是應用程式可能會用，但如果是用在函式庫的話，因為同時會限制到使用怎麼使用函式庫，所以函式庫的作者可能比較不會去用，畢竟會變成需要傳入 logger ，目前看來，如果需要簡單的 log 功能就用 log 吧，如果需要複雜的功能， tracing 看來會很適合